"""for cRNC

update:
  2014-06-23: add PLAN_PROGRESS '2C1D'
"""


import os
import re
import time
import datetime
import logging

import crnclib
import xml_tool
import counter_tool
from crnclib import CRNC_UNIT

# Constants for Emil log.
CRNC_FAM = {
    'ICSU' : {
        "A2S": "0452", "AIM": "03C9", "RM2": "04B4", "UER": "0997",
        "NBA": "04FE", "NRM": "04B7", "RRB": "09B7", "IUV": "0509",
        "IUR": "0508", "NRR": "09F6", "RRC": "04FD", "NRC": "09BA",
        "RC3": "04FC", "RRA": "09B6", "HA3": "0507", "BRM": "04FB",
        "RBR": "054E", "A2S": "0452", "L3C": "0A49"
        #"L2M": "06EA"
    },
    'ICSU_cond' : "0001,0002,99B6,99BB,99B7,9907,9948,992E",
    'OMU' : {
        "REZ": "04FA", "RAK": "04EE", "RAV": "050A", "EXW": "0433",
        "RBR": "054E", "VEX": "04EF", "REK": "050B", "RAY": "0523",
        "ENP": "0553", "PAB": "0524", "JIG": "047A"
    },
    'OMU_cond' : "0001,0002,0003,0D5C6"
}

# Constants for plan management.
PLAN_TASK_ID_REQ_ACK   = "D80C"  # plan_task_id_request_ack_s
PLAN_SCHEMA_VERSION    = "D5FA"  # rnw_plan_schema_version_s
PLAN_DL_ACK            = "D7FD"  # rnw_plan_download_ack_s
PLAN_DL_END_MSG        = "D7FB"  # rnw_plan_download_end_s
PLAN_ACT_ACK           = "D7F9"  # rnw_plan_activation_ack_s
PLAN_ACT_END_MSG       = "D7F8"  # rnw_plan_activation_end_s
PLAN_UL_ACK            = "D7F6"  # rnw_plan_upload_ack_s
PLAN_UL_END_MSG        = "D7F5"  # rnw_plan_upload_end_s
PLAN_FEEDBACK_ACK      = "D7F3"  # rnw_plan_feedback_ack_s
PLAN_FEEDBACK          = "D7F4"  # rnw_plan_feedback_s
PLAN_PROGRESS          = "2C1D"
TASK_ID_GLOBAL_DL      = "10,10,10,10"
TASK_ID_GLOBAL_ACT     = "11,11,11,11"
TASK_ID_GLOBAL_UL      = "12,12,12,12"
PLAN_ID_GLOBAL         = "33,33,33,33"
TASK_ID_DUMMY          = "00,00,00,00"
PLAN_ACT_MODE          = "00"  # "00"-safe mode "10"-normal mode "20"-fast mode


class Crnc(crnclib.BaseCrnc):
    def __init__(self, *args, **kwargs):
        crnclib.BaseCrnc.__init__(self, *args, **kwargs)
        self.type = self.name.split('_')[0]
        self.checked = False
        self.counter_dir = "/shadows/VIDAST"
        self.time_counter = None  # the time when counter stop

        self.emil_units = {}
        for var in CRNC_UNIT:
            self.emil_units[var] = False
        self.emil_units[CRNC_UNIT[0]] = True
        self.enable_comp_log = False

    def set_emil_units(self, units):
        self.emil_units = units

    def get_emil_units(self):
        return self.emil_units

    def set_comp_log(self, var):
        self.enable_comp_log = var

    def disconnect(self):
        self.close()
        self.checked = False

    def create_localpath(self, path):
        if path and not os.path.isdir(path):
            os.makedirs(path)
            self.log('info', "Create local path " + path)
            return True
        else:
            return False

    def get_casename(self, logpath):
        foldername = os.path.basename(logpath)
        timestamp = re.findall(r"\d{8}_\d{6}", foldername)
        if not timestamp:
            return foldername
        splits = foldername.split(timestamp[0])
        if len(splits) >0 and splits[1]:
            head = splits[1][1:]
        else:
            head = splits[0][:-1]
        return "%s_%s" % (head, timestamp[0])

    def check(self, force=False):
        if self.connected and self.checked and not force:
            return True

        if not (self.connected or self.connect()):
            return False

        if force or not self.checked:
            self.log("notice", "Checking %s info " % self.name, set_index='rnc_check')
            #self.logger.mark_set('rnc_check')
            self.checked = self.check_unit()
            kwargs = dict(head='', end='', index='rnc_check', unset_index='rnc_check')
            if self.checked:
                self.log("notice", "successful", tag='g', **kwargs)
                self.log("info", "Package info: %s" % self.get_package())
                self.log("info", "Build info: %s" % self.get_build_info())
            else:
                self.log("notice", "failed", tag='r', **kwargs)
        return self.checked

    def catch_emil_stop(self):
        if not self.check():
            return False
        unit_num = 0
        
        kwargs = dict(head='', end=' ', index='emil lineend')
        for unit in CRNC_UNIT :
            if self.emil_units[unit]:
                if unit_num == 0:
                    self.log('notice', "Stop catch Emil at ", set_index='emil')
                self.log('notice', unit, **kwargs)
                self.catch_emil_stop_unit(unit)
                unit_num += 1
        if unit_num == 0:
            self.log('warn', "No active unit to stop emil.")
            return False
        else:
            kwargs['unset_index'] = 'emil'
            #kwargs['tag'] = 'g'
            self.log('notice', 'done', **kwargs)
            return True

    def catch_emil_stop_unit(self, unit):
        phys = self.get_unit_pyhs(unit)
        self.log('debug', "Stop catch emil at %s(%s)" % (unit, phys))
        self.chdir("OMU")
        self.send("ZOES:" + phys)
        self.send("ZOEI:" + phys)
        self.chdir("main")

    def catch_emil(self):
        if not self.check():
            return False
        unit_num = 0
        kwargs = dict(head='', end=' ', index='emil lineend')
        for unit in CRNC_UNIT :
            if self.emil_units[unit]:
                if unit_num == 0:
                    self.log('notice', "Start catch Emil at ", set_index='emil')
                self.log('notice', unit, **kwargs)
                cond = "SR:(OFAM=%s)AND(NOT(NUM=%s))" % \
                    (','.join(CRNC_FAM[unit].values()), CRNC_FAM[unit+"_cond"])
                self.catch_emil_unit(unit, self.emil_units['ICSU'], cond)
                unit_num += 1
        if unit_num == 0:
            self.log('warn', "No active unit to catch emil.")
            return False
        else:
            kwargs['unset_index'] = 'emil'
            #kwargs['tag'] = 'g'
            self.log('notice', 'done', **kwargs)
            return True

    def catch_emil_unit(self, unit, ha3, cond):
        phys = self.get_unit_pyhs(unit)
        self.log('debug', "Start catch emil at %s(%s)" % (unit, phys))
        active_unit = "%s,%s" % (unit, self.get_unit_id(unit))
        self.chdir("OMU")
        self.send("ZOEQ:" + phys)
        # enlarge the monitoring buffer to EFFFFFF=251658239=250M
        self.send("ZOEBR:%s:EFFFFFF,0" % phys)
        self.send("ZOEC:%s:%s;" % (phys, cond))
        self.send("ZOEM:" + phys)
        self.chdir("main")
        self.send('ZDDE:%s:"ZGC";' % active_unit)
        self.send('ZDDE:%s:"ZGR";' % active_unit)
        self.send('ZDDE:%s:"ZGE:80000";' % active_unit)
        if ha3:
            self.chdir(unit)
            self.send("ZOS:*,*,507,,,,,C50D,,,FE,XW0,XW0,XW0,XW0,XW1,XW0;")
            self.chdir("main")

    def collect_emil(self, logpath):
        if not self.check():
            return False
        unit_num = 0
        for unit in CRNC_UNIT :
            if self.emil_units[unit]:
                self.collect_emil_unit(unit, logpath)
                unit_num += 1
        if unit_num == 0:
            self.log('warn', "No active unit to collect emil.")
            return False
        else:
            return True

    def collect_emil_unit(self, unit, logpath):
        phys = self.get_unit_pyhs(unit)
        self.create_localpath(logpath)
        self.chdir("OMU")
        logname = "RNCLOG%s.BIN" % phys
        self.log('info', "Collect cRNC %s Emil to %s" % (unit, logname))
        self.send(r"ZOEGF:%s:W0-/%s;" % (phys, logname))
        remotefile = "/shadows/" + logname
        logname = "%s_%s.bin" % (self.get_casename(logpath), unit.upper())
        localfile = "%s\\%s" % (logpath, logname)
        self.get(remotefile, localfile, "Emil log", True)
        
        if self.enable_comp_log:
            comp_logname = "%s_%s_comp.txt" % (self.get_casename(logpath), unit.upper())
            logfile = "%s\\%s" % (logpath, comp_logname)
            self.collect_comput_log(unit, logfile)

        self.chdir("main")

    def check_meas(self):
        if not self.connected:
            return False
        self.send_pom_cmd("ls", "/RUNNING/PLATMP/MEASPLAN.XML")
        if "No such file" in self.stdout:
            self.log('warn', "No MEASPLAN.XML found. Please active counter at first.")
            return False
        else:
            return True

    def active_counter(self):
        if not self.check():
            return False
        self.log('info', "Start active counter")
        measplan = "MEASPLAN.XML"
        remotefile = "/RUNNING/PLATMP/%s" % measplan
        localfile = "%s\\tools\\%s" % (os.getcwd(), measplan)
        if not self.put(localfile, remotefile):
            return False
        self.chdir("OMU")
        self.send("ZOS:*,*,04ED,0000,00,00,0000,0D45,," + ",XD00"*5);
        self.send("ZOS:*,*,04ED,0000,00,00,0000,0D47,,,XD00");
        return True

    def catch_counter(self):
        """just for RN6.0 and later"""
        if not self.check() or not self.check_meas():
            return False
        self.chdir("main")
        self.log('info', "Mark all measurement files as transferred")
        self.send("ZIFS:OMU:GENE00:1&&100,:T;")
        self.send("ZIFS:OMU:GENE00::INITIALIZE:;")
        self.chdir("OMU")
        self.send("ZLP:M,MAS")
        time.sleep(1.0)
        self.log('info', "Delete all old measurement files")
        self.send(r"ZMD:W0-/VIDAST/*.D00")
        self.send(r"ZMD:W0-/VIDAST/COMP00/*.Z")
        self.chdir("OMU")
        self.send("ZOS:*,*,04ED,0000,00,00,0000,11AA,,,XD00");
        self.log('info', "Catch cRNC counter at " + self.get_date())
        return True

    def catch_counter_stop(self):
        if not self.check() or not self.check_meas():
            return False
        self.log('info', "Stop catch cRNC counter")
        self.chdir("main")
        self.send("ZIFS:OMU:GENE00::INITIALIZE:;")
        self.chdir("OMU")
        self.send("ZLP:M,MAS")
        time.sleep(1.0)
        # delete all old measurement files
        self.send("ZMD:W0-/VIDAST/*.D00")
        time.sleep(1.0)
        self.time_counter = self.get_date()
        self.log('info', "Counter stopped at " + self.time_counter)
        self.chdir("OMU")
        self.send("ZOS:*,*,04ED,0000,00,00,0000,11AA,,,XD01");
        return True

    def collect_counter(self, logpath):
        if not self.check() or not self.check_meas():
            return False
        if not self.time_counter:
            self.log('warn', "Skipped due to counter not started.")
            return False
        self.log('notice', "Waiting for cRNC counter files")
        self.chdir("main")
        meas_files = []
        findmeas = -1
        d = r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}"
        prog = re.compile(r"(\d+)  [A-Z]+ +OK/OK     - - -   ({0})".format(d))
        f = "%Y-%m-%d %H:%M:%S"
        start_time = datetime.datetime.strptime(self.time_counter, f)
        self.time_counter = None

        while findmeas != len(meas_files):
            findmeas = len(meas_files)
            time.sleep(5.0)
            self.send("ZIFO:OMU:GENE00;")

            new_files = []
            for num, date in prog.findall(self.stdout):
                if "00:00:00" in date:
                    continue
                filename = "DF%04d.D00" % int(num)
                if filename not in meas_files:
                    finish = datetime.datetime.strptime(date, f)
                    if finish >= start_time:
                        new_files.append(filename)
                        if len(new_files) == 1:
                            self.log('notice', "New meas files found:", end=' ')
                        self.log('notice', filename, head='', end=' ')
            if new_files:
                meas_files.extend(new_files)

        if meas_files:
            self.log('notice', '', head='', end=' ')
            self.log('debug', "found measurement files: " + ', '.join(meas_files))
            self.create_localpath(logpath)
            measname = "%s\\%s_meas.txt" % (logpath, self.get_casename(logpath))
            rslt = counter_tool.decode_crnc(self.info.hostname, ';'.join(meas_files), measname)
            if rslt:
                self.log('info', "Decode counter " + rslt)
                self.log('notice', "Collect counter to %s" % measname)
        else:
            self.log('warn', "No measurement file found.")
        return True

    def collect_comput_log(self, unit, filename):
        if unit not in CRNC_UNIT:
            return False
        self.chdir("main")
        with open(filename, 'w') as outfile:
            self.send("ZUSI::WO-ALL,:FULL;")
            outfile.write(self.allout)
            self.chdir(unit)
            outfile.write(self.allout)
            for cmd in ("ZGDIC", "ZGSC", "ZSLP", "ZGR", "ZSS"):
                self.send(cmd)
                outfile.write(self.allout)
            self.log('info', "Collect %s computer log to %s" % (unit, os.path.basename(filename)))
        return True

    def collect_plan(self, logpath=None):
        if not self.check():
            return False
        if logpath is None:
            logpath = os.environ.get('TEMP')
            t = time.strftime("%Y%m%d_%H%M%S", time.localtime())
        else:
            
            foldername = os.path.basename(logpath)
            t = re.findall(r"\d{8}_\d{6}", foldername)[0]
        localxml = "{0}\\{1}_{2}_{3}_{4}.xml".format(
                    logpath, self.name, self.build, self.corr, t)
        if self.upload_plan(localxml):
            return localxml
        else:
            return False

    def download_active_plan(self, xml, trace):
        if self.download_plan(xml, trace) and self.active_plan():
            logger = logging.getLogger('rnw_plan')
            logger.info("%s - %s(%s %s) - %s" % (self.name, self.package, self.build, self.corr, xml))
            return True
        else:
            return False

    def download_plan(self, xml, trace):
        if not self.check():
            return False
        self.log('info' ,"Start download RNW Plan %s." % xml)
        self.clear_omu_buffer()
        if not self.wait_noraml_db_state():
            return False

        self.chdir("OMU")
        # Send task_id and plan_id for plan download
        mml = "ZOS:*,*,523,,,,,D80D,,,10,{0},{1},{2}".format(
                 TASK_ID_GLOBAL_DL, PLAN_ID_GLOBAL, TASK_ID_DUMMY
              )
        self.send(mml)
        for times in xrange(50):
            if self.wait_ack_msg(PLAN_TASK_ID_REQ_ACK):
                break
            else:
                time.sleep(10.0*(times+1))
        else:
            self.log('notice', "Set plan task id failed.")
            return False

        # D7FE is "rnw_plan_download_req_s" NEMU --> RAYMAN,
        # starts the RNW plan download operation in RNC DX.
        mml = "ZOS:*,*,523,,,,,D7FE,,,{0},00".format(TASK_ID_GLOBAL_DL);
        self.send(mml)
        if not self.wait_ack_msg(PLAN_DL_ACK):
            self.log('notice', "Plan download ack failed.")
            return False

        remote_plan = "/RUNNING/PLATMP/RNWPLAND.XML"
        if not self.put(xml, remote_plan, "RNW plan"):
            return False

        # D7FC "plan_file_ready_s"
        # This message indicates to that plan file downloading
        # to RNC disk is completed .
        mml = "ZOS:*,*,523,01,,,,D7FC,,,00,00,00,00"
        self.send(mml)
        if not self.wait_ack_msg(PLAN_SCHEMA_VERSION):
            self.log('notice', "Plan file is not ready.")
            return False

        if trace:
            # D01A "rnw_plan_schema_version_ack_s" NEMU --> RAYMAN ,
            # it is an acknowledgement to the message rnw_plan_schema_version_s,
            # informing that plan operation may continue.
            mml = "ZOS:*,*,523,1,,,,D01A,,,00,00,00,00"
            self.send(mml)

            # receive first feedback and send feedback request to RAYMAN
            mml = "ZOS:*,*,523,1,,,,B2D2,,,FF,FF,FF,FF"
            self.send(mml)

        if not self.check_operate_result(PLAN_DL_END_MSG):
            self.log('notice', "Plan rollback failed.")
            return False

        self.clear_omu_buffer(False)
        self.log('notice', "Download plan successful.")

        return True

    def active_plan(self):
        if not self.check():
            return False
        self.log('info' ,"Start active plan.")
        self.clear_omu_buffer()
        if not self.wait_noraml_db_state():
            return False

        self.chdir("OMU")
        # Send task_id and plan_id for plan download
        mml = "ZOS:*,*,523,,,,,D80D,,,11,{0},{1},{2}".format(
                TASK_ID_GLOBAL_ACT, PLAN_ID_GLOBAL, TASK_ID_DUMMY
              )
        self.send(mml)
        for times in xrange(50):
            if self.wait_ack_msg(PLAN_TASK_ID_REQ_ACK):
                break
            else:
                time.sleep(10.0*(times+1))
        else:
            self.log('notice', "Set plan task id failed.")
            return False

        # rnw_plan_activation_req_s RN7.0
        mml = "ZOS:*,*,523,,,,,D7FA,,,{0},{1},02".format(
                TASK_ID_GLOBAL_ACT, PLAN_ACT_MODE
              )
        self.send(mml)
        if not self.wait_ack_msg(PLAN_ACT_ACK):
            self.log('notice', "Plan activation act failed.")
            return False

        if not self.check_operate_result(PLAN_ACT_END_MSG):
            self.log('notice', "Plan activation check operate result failed.")
            return False

        self.clear_omu_buffer(False)
        self.log('notice', "Active plan successful.")
        return True

    def upload_plan(self, xml):
        if not self.check():
            return False
        self.log('info' ,"Upload cRNC RNW Plan.")
        self.clear_omu_buffer()
        if not self.wait_noraml_db_state():
            return False

        self.chdir("OMU")
        # upload plan downloadable
        mml = "ZOS:*,*,524,,,,,FACC,,,00,BC,00,00,00,00"
        self.send(mml)

        # Send task_id for plan upload (message plan_task_id_request_s)
        mml = "ZOS:*,*,523,,,,,D80D,,,12,{0},00,00,00,00,{1}".format(
            TASK_ID_GLOBAL_UL, TASK_ID_DUMMY)
        self.send(mml)
        for times in xrange(50):
            if self.wait_ack_msg(PLAN_TASK_ID_REQ_ACK):
                break
            else:
                time.sleep(10.0*(times+1))
        else:
            self.log('notice', "Set plan task id failed.")
            return False

        # D7F7 is "rnw_plan_upload_req_s" NEMU --> RAYBAN
        # Starts the RNW plan (configuration) upload operation in RNC DX.
        mml = "ZOS:*,*,523,,,,,D7F7,,,{0},,,,,,,,".format(TASK_ID_GLOBAL_UL)
        self.send(mml)
        if not self.wait_ack_msg(PLAN_UL_ACK):
            self.log('notice', "Wait plan upload act failed.")
            return False

        if not self.check_operate_result(PLAN_UL_END_MSG):
            self.log('notice', "Check plan upload operate failed.")
            return False

        self.create_localpath(os.path.dirname(os.path.abspath(xml)))

        remotefile = "/RUNNING/PLATMP/RNWPLANU.XML"
        if not self.get(remotefile, xml, "RNW plan", True):
            return False

        self.clear_omu_buffer(False)
        self.log('notice', "Upload plan successful.")

        return xml_tool.tidy_plan(xml)

    def decode_ascii(self, msg):
        """decode ASCII to strings"""
        str_list = []
        for var in msg.split():
            if var == "00" or int(var, 16) < 32 or int(var, 16) >= 127:
                continue
            else:
                str_list.append(chr(int(var, 16)))
        self.log('debug', ''.join(str_list))
        if len(str_list) > 2:
            self.log('notice', ''.join(str_list))

    def wait_noraml_db_state(self):
        self.chdir("main")
        prog = re.compile(r"RAQUEL\s+\w+\s+WO\s+(\w+)")
        db_state = None
        err_msg = None
        self.log('info', "Checking RNW db state", end=' ')
        for times in xrange(20):
            if times > 0:
                time.sleep(0.5)
            self.send("ZDBS:RAQUEL,0:;")
            states = prog.findall(self.stdout)
            if states:
                db_state = states[0]
            else:
                continue

            if not db_state:
                err_msg = "Can not find RAQUEL DB status!"
                rslt = False
                break
            elif db_state == "NORMAL":  # RNW database is in normal state 
                self.log('notice', "NORMAL", head='', end=' ')
                rslt = True
                break
            elif db_state == "WAITING":
                # RNW database not in normal state, waiting...
                self.log('notice', "WAITING", head='', end=' ')
                # "Force RNW DB dump with MML..."
                mml = "ZDBC:RAQUEL,0:SFTY=2,PHASE=START,MODE=BACK,TRANS=PREV;"
                self.send(mml, regex="Y/N ?", timeout=3.0, std=False)
                self.send("Y", timeout=1.0)
            time.sleep(10.0)
        else:
            err_msg = "Checking RNW db state time out."
            rslt = False
        if rslt:
            self.log('notice', "successful", head='', tag='g')
        else:
            self.log('notice', "failed", head='', tag='g')
            self.log('error', err_msg)
        return rslt

    def wait_ack_msg(self, ack_msg, timeout=180):
        msg_type = None
        err_msg = None
        self.log('info', "Wait ack message %s " % ack_msg, set_index='wait_ack')
        kwargs = dict(head='', end='', index='wait_ack', unset_index='wait_ack')
        for times in xrange(timeout):
            if times > 0:
                time.sleep(0.5)
            self.send("ZOT")
            if "NO MESSAGE" in self.stdout:
                time.sleep(1.5)
                continue
            types = re.findall(r"RECEIVED MESSAGE:[ \w]{32}(\w+)", self.stdout)
            if types:
                msg_type = types[0]
            else:
                continue

            lines = re.findall(r"^([0-9A-F]{2}(?: \w\w)*)", self.stdout, re.M)
            if lines:
                self.decode_ascii(' '.join(lines))

            if msg_type == ack_msg:
                rslt = True
                break
            elif msg_type == PLAN_FEEDBACK or msg_type == PLAN_PROGRESS:
                # unexpected feedback message received, skip...
                continue
            else:
                err_msg = "Unexpected ack message '%s' received." % msg_type
                rslt = False
                break
        else:
            err_msg = "Wait ack message %s time out." % ack_msg
            rslt = False

        if rslt:
            self.log('notice', "successful", tag='g', **kwargs)
        else:
            self.log('notice', "failed", tag='r', **kwargs)
            if err_msg:
                self.log('error', err_msg)

        return rslt

    def check_operate_result(self, end_msg, timeout=180):
        msg_type = None
        err_msg = None
        trace_err = False
        self.log('info', "Checking operate result %s " % end_msg, set_index='check_opera')
        kwargs = dict(head='', end='', index='check_opera', unset_index='check_opera')
        for times in xrange(timeout):
            if times > 0:
                time.sleep(0.5)
            self.send("ZOT")
            if "NO MESSAGE" in self.stdout:
                time.sleep(1.5)
                continue
            types = re.findall(r"RECEIVED MESSAGE:[ \w]{32}(\w+)", self.stdout)
            if types:
                msg_type = types[0]
            else:
                continue

            lines = re.findall(r"^([0-9A-F]{2}(?: \w\w)*)", self.stdout, re.M)
            if lines:
                self.decode_ascii(' '.join(lines))

            if msg_type == PLAN_DL_END_MSG \
                or msg_type == PLAN_ACT_END_MSG:
                states = re.findall(r"RECEIVED.*\n(.{11})", self.stdout)
                if states:
                    state = states[0]
                else:
                    continue
            elif msg_type == PLAN_UL_END_MSG:
                states = re.findall(r"RECEIVED.*\n.*\n.*\n.{54}(.{11})", 
                                    self.stdout)
                if states:
                    state = states[0]
                else:
                    continue
            elif msg_type == PLAN_FEEDBACK \
                or msg_type == PLAN_FEEDBACK_ACK \
                or msg_type == PLAN_SCHEMA_VERSION \
                or msg_type == PLAN_DL_ACK \
                or msg_type == PLAN_PROGRESS:
                continue
            else:
                err_msg = "Unexpected result message %s received." % msg_type
                rslt = False
                break

            if state != "00 00 00 00":
                err_msg = "error state '%s' detected." % state
                trace_err = True
                rslt = False
                break
            else:
                rslt = True  # Plan operation finished.
                break
        else:
            err_msg = "Checking operate result %s time out." % end_msg
            rslt = False

        if rslt:
            self.log('notice', "successful", tag='g', **kwargs)
        else:
            self.log('notice', "failed", tag='r', **kwargs)
            if err_msg:
                self.log('error', err_msg)
            if trace_err:
                self.log('notice', "wait trace omu err ...")
                self.trace_omu_err(False)

        return rslt

